Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

*: refactor slow log format and parse slow query log to SLOW_QUERY table. #9290

Merged
merged 39 commits into from
Mar 11, 2019

Conversation

crazycs520
Copy link
Contributor

@crazycs520 crazycs520 commented Feb 12, 2019

What problem does this PR solve?

  • refactor slow log format to compatible with mysql slow log.
  • Add INFORMATION_SCHEMA.SLOW_QUERY table, the table content is from parse slow log file.
  • Add tidb_slow_query_file seesion variable to control which slow log file to be parsed.

What is changed and how it works?

  • New slow log format is like below, this will be friendly to some utils like pt-query-digest.

    # Time: 2019-02-12-19:33:56.571953 +0800
    # Txn_start_ts: 406315658548871171
    # User: [email protected]
    # Conn_ID: 6
    # Query_time: 4.895492
    # Process_time: 0.161 Request_count: 1 Total_keys: 100001 Processed_keys: 100000
    # DB: test
    # Is_internal: false
    select * from t_slim;
    
    • other information like statement digest, plan digest maybe add later.
    • If you need more information in slow log, please leave you comment.
  • Query INFORMATION_SCHEMA.SLOW_QUERY table.

    mysql> use INFORMATION_SCHEMA;
    Database changed
    mysql> set @@tidb_slow_query_file="tidb_slow.log";
    Query OK, 0 rows affected (0.00 sec)
    mysql> select * from `SLOW_QUERY`;
    +----------------------------+--------------------+----------------+---------+------------+--------------+-----------+--------------+---------------+------------+----------------+------+-------------+--------------------------------------------------+
    | Time                       | Txn_start_ts       | User           | Conn_ID | Query_time | Process_time | Wait_time | Backoff_time | Request_count | Total_keys | Processed_keys | DB   | Is_internal | Query                                            |
    +----------------------------+--------------------+----------------+---------+------------+--------------+-----------+--------------+---------------+------------+----------------+------+-------------+--------------------------------------------------+
    | 2019-02-12 19:31:06.954777 | 406315605634056194 | root@127.0.0.1 |       1 |  37.142122 |         NULL |      NULL |         NULL |          NULL |       NULL |           NULL | test |           0 | create table t1(y year NOT NULL DEFAULT '2155'); |
    | 2019-02-12 19:33:56.571953 | 406315658548871171 | root@127.0.0.1 |       6 |   4.895492 |        0.161 |      NULL |         NULL |             1 |     100001 |         100000 | test |           0 | select * from t_slim;                            |
    | 2019-02-12 19:34:33.257245 |                  0 | NULL           |    NULL |    0.51371 |         NULL |      NULL |         NULL |          NULL |       NULL |           NULL | NULL |           1 | analyze table `test`.`t_slim`;                   |
    +----------------------------+--------------------+----------------+---------+------------+--------------+-----------+--------------+---------------+------------+----------------+------+-------------+--------------------------------------------------+
    3 rows in set (0.00 sec)
    
    mysql> select * from `SLOW_QUERY` where `Is_internal`=false order by `Query_time` desc;
    +----------------------------+--------------------+----------------+---------+------------+--------------+-----------+--------------+---------------+------------+----------------+------+-------------+--------------------------------------------------+
    | Time                       | Txn_start_ts       | User           | Conn_ID | Query_time | Process_time | Wait_time | Backoff_time | Request_count | Total_keys | Processed_keys | DB   | Is_internal | Query                                            |
    +----------------------------+--------------------+----------------+---------+------------+--------------+-----------+--------------+---------------+------------+----------------+------+-------------+--------------------------------------------------+
    | 2019-02-12 19:31:06.954777 | 406315605634056194 | root@127.0.0.1 |       1 |  37.142122 |         NULL |      NULL |         NULL |          NULL |       NULL |           NULL | test |           0 | create table t1(y year NOT NULL DEFAULT '2155'); |
    | 2019-02-12 19:33:56.571953 | 406315658548871171 | root@127.0.0.1 |       6 |   4.895492 |        0.161 |      NULL |         NULL |             1 |     100001 |         100000 | test |           0 | select * from t_slim;                            |
    +----------------------------+--------------------+----------------+---------+------------+--------------+-----------+--------------+---------------+------------+----------------+------+-------------+--------------------------------------------------+
    2 rows in set (0.00 sec)

Check List

Tests

  • Unit test
  • Integration test

Code changes

  • Has exported function/method change

Side effects

Related changes

  • Need to update the documentation

@crazycs520 crazycs520 added type/enhancement The issue or PR belongs to an enhancement. type/usability labels Feb 12, 2019
@morgo
Copy link
Contributor

morgo commented Feb 12, 2019

Assuming that a statement_digest function is added in pingcap/parser#32, it should be possible to group by digested form :-)

I myself will process the log file in a utility like pt-query-digest, but I can see the use case of presenting in the server (in the absense of pfs for this as in MySQL).

@jackysp
Copy link
Member

jackysp commented Feb 13, 2019

There may be some conflictions between this PR and #9279 .

@lysu
Copy link
Contributor

lysu commented Feb 13, 2019

@crazycs520 I have a question, do we keep old slow-log in tidb.log file and put new format into new tidb-slow.log file? or just replace old format with the new one?

new format maybe friendly to pt but it seems not friendly to grep & awk script

@morgo
Copy link
Contributor

morgo commented Feb 13, 2019

@crazycs520 I have a question, do we keep old slow-log in tidb.log file and put new format into new tidb-slow.log file? or just replace old format with the new one?

It is a good question. I would rather we don't have two formats. It feels wrong to ask a customer which slow log format they are using when we are suggesting tools to process it.

new format maybe friendly to pt but it seems not friendly to grep & awk script

I think medium term we should offer a pt-query-digest alternative based on https://github.com/Preetam/mysqllog + using our parser for normalization :-) It is quick to build, and will save users from installing perl.

executor/adapter.go Outdated Show resolved Hide resolved
util/execdetails/execdetails.go Outdated Show resolved Hide resolved
sessionctx/variable/session.go Outdated Show resolved Hide resolved
infoschema/slow_log.go Outdated Show resolved Hide resolved
infoschema/slow_log_test.go Show resolved Hide resolved
@crazycs520
Copy link
Contributor Author

@zz-jason @zimulala PTAL.

@crazycs520
Copy link
Contributor Author

/run-all-tests

Copy link
Contributor

@winkyao winkyao left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

sessionctx/variable/session.go Show resolved Hide resolved
util/execdetails/execdetails.go Outdated Show resolved Hide resolved
util/execdetails/execdetails.go Outdated Show resolved Hide resolved
infoschema/tables_test.go Outdated Show resolved Hide resolved
infoschema/slow_log.go Outdated Show resolved Hide resolved
infoschema/slow_log.go Outdated Show resolved Hide resolved
infoschema/slow_log.go Outdated Show resolved Hide resolved
infoschema/slow_log.go Outdated Show resolved Hide resolved
infoschema/slow_log.go Outdated Show resolved Hide resolved
infoschema/slow_log.go Outdated Show resolved Hide resolved
@crazycs520
Copy link
Contributor Author

@zz-jason PTAL.

infoschema/slow_log.go Show resolved Hide resolved
infoschema/slow_log.go Show resolved Hide resolved
infoschema/slow_log.go Show resolved Hide resolved
infoschema/slow_log.go Outdated Show resolved Hide resolved
infoschema/slow_log.go Show resolved Hide resolved
util/execdetails/execdetails.go Outdated Show resolved Hide resolved
sessionctx/variable/session.go Show resolved Hide resolved
sessionctx/variable/session_test.go Outdated Show resolved Hide resolved
util/execdetails/execdetails.go Outdated Show resolved Hide resolved
buf.WriteString(SlowLogPrefixStr + SlowLogIndexNamesStr + SlowLogSpaceMarkStr + indexIDs + "\n")
}
buf.WriteString(SlowLogPrefixStr + SlowLogIsInternalStr + SlowLogSpaceMarkStr + strconv.FormatBool(s.InRestrictedSQL) + "\n")
if len(sql) > 0 {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Under what circumstances will encounter the situation of len(sql) == 0 ?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Normally It won't be len(sql) = 0, but just in case, we should also print ";" when len(sql)=0. Parser need ";" to indicate the end of slow log.

sessionctx/variable/session.go Outdated Show resolved Hide resolved
executor/adapter.go Show resolved Hide resolved
@crazycs520
Copy link
Contributor Author

@zz-jason @zimulala PTAL again. Thanks.

Copy link
Member

@zz-jason zz-jason left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@zz-jason
Copy link
Member

/run-all-tests

@zz-jason zz-jason removed the request for review from XuHuaiyu March 11, 2019 06:34
@zz-jason zz-jason merged commit 80110fb into pingcap:master Mar 11, 2019
}
defer func() {
if err = file.Close(); err != nil {
log.Error(err)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please add more information to this log.


const (
// SlowLogPrefixStr is slow log row prefix.
SlowLogPrefixStr = "# "
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could we rename it to SlowLogFieldPrefixStr or SlowLogRowPrefixStr?

totalKeys uint64
processKeys uint64
db string
indexNames string
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we need to update this field name?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type/enhancement The issue or PR belongs to an enhancement. type/usability
Projects
None yet
Development

Successfully merging this pull request may close these issues.

9 participants